Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

tracing: less noisy, more useful log records for spans #613

Merged
merged 6 commits into from
Feb 28, 2020

Conversation

hawkw
Copy link
Member

@hawkw hawkw commented Feb 28, 2020

Motivation

Currently, the tracing crate's "log" feature always logs span
lifecycle (creation/enter/exit/close) events, even when the span has no
fields. This can be quite noisy. Since the enter, exit, and close logs
don't include the span's fields, it doesn't add that much additional
context to the surrounding log records.

Additionally, when using tracing with the log-always feature and a
subscriber is active, the IDs of enabled spans are available, but not
included in the span lifecycle log records. These could be used to
enable tracking individual span's lifecycles via these log records, but
this is not currently possible.

Solution

In order to continue recording this data while improving the
signal-to-noise ratio of tracing-generated logs, this branch changes
the log integration to log span lifecycle events under a separate
target, "tracing::span". This way, log users can opt in to this data
when it is desired, but logs are generally much less noisy. Span
creation is still logged to the default target when the span has fields,
as this often provides useful information, but is sent to the
"tracing-span" target when there are no fields.

This branch also updates the log integration so that when a span is
enabled by a subscriber, and log integration is enabled, that span's
log records will include its ID. Now, when multiple spans with the
same name are in the logs, we have a rudimentary ability to correlate
those span's lifecycle events, without introducing so much complexity
that just using a tracing subscriber would be a better solution.

For example, when a subscriber is assigning IDs to spans, the logs look
like this:

ERROR log_with_trace foo=5
ERROR log_with_trace foo=42
ERROR log_with_trace foo=39
WARN  log_with_trace hello world;
INFO  log_with_trace hello world; thingy=42 other_thingy=666
TRACE tracing::span ++ foo; span=1
TRACE tracing::span -> foo; span=1
TRACE log_with_trace hello san francisco; foo=3 bar=4
TRACE tracing::span <- foo; span=1
TRACE tracing::span -- foo; span=1
TRACE log_with_trace ++ foo; bar=3 baz=false; span=2
TRACE tracing::span -- foo; span=2
TRACE log_with_trace hello world foo=1 bar=2

Finally, I've added a new section to the tracing crate's documentation
to provide details on using the log integration features.

Fixes #607

Signed-off-by: Eliza Weisman eliza@buoyant.io

## Motivation

Currently, the `tracing` crate's "log" feature always logs span
lifecycle (creation/enter/exit/close) events, even when the span has no
fields. This can be quite noisy. Since the enter, exit, and close logs
don't include the span's fields, it doesn't add that much additional
context to the surrounding log records.

## Solution

In order to continue recording this data while improving the
signal-to-noise ratio of `tracing`-generated logs, this commit changes
the log integration to log span lifecycle events under a separate
target, "tracing::span". This way, log users can opt in to this data
when it is desired, but logs are generally much less noisy. Span
creation is still logged to the default target when the span has fields,
as this often provides useful information, but is sent to the
"tracing-span" target when there are no fields.

Fixes #607
When using `tracing` with the `log-always`, the IDs of enabled spans are
available, but not included in the span lifecycle `log` records. These
could be used to enable tracking individual span's lifecycles via these
log records, but this is not currently possible.

This commit updates the `log` integration so that when a span is enabled
by a subscriber, and `log` integration is enabled, that span's `log`
records will include its ID. Now, when multiple spans with the same name
are in the logs, we have a rudimentary ability to correlate those span's
lifecycle events, without introducing so much complexity that just using
a `tracing` subscriber would be a better solution.

For example, when a subscriber is assigning IDs to spans, the logs look
like this:

```
ERROR log_with_trace foo=5
ERROR log_with_trace foo=42
ERROR log_with_trace foo=39
WARN  log_with_trace hello world;
INFO  log_with_trace hello world; thingy=42 other_thingy=666
TRACE tracing::span ++ foo; span=1
TRACE tracing::span -> foo; span=1
TRACE log_with_trace hello san francisco; foo=3 bar=4
TRACE tracing::span <- foo; span=1
TRACE tracing::span -- foo; span=1
TRACE log_with_trace ++ foo; bar=3 baz=false; span=2
TRACE tracing::span -- foo; span=2
TRACE log_with_trace hello world foo=1 bar=2
```

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw added kind/feature New feature or request crate/tracing Related to the `tracing` crate labels Feb 28, 2020
@hawkw hawkw requested a review from a team February 28, 2020 19:27
@hawkw hawkw self-assigned this Feb 28, 2020
@hawkw
Copy link
Member Author

hawkw commented Feb 28, 2020

cc @sagebind — this is what we discussed in #607

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
tracing/src/lib.rs Outdated Show resolved Hide resolved
Co-Authored-By: David Barsky <me@davidbarsky.com>
@hawkw hawkw merged commit 120f852 into master Feb 28, 2020
@sagebind
Copy link

Awesome! 🎉

@sagebind
Copy link

Sorry for the bump, any chance of getting a tracing 0.1.14 out there with this in it? It's sort of a blocker for me to adopt it in a public release of my own crate.

@hawkw
Copy link
Member Author

hawkw commented May 14, 2020

@sagebind whoops, I forgot that this hadn't been published yet. Will get that out ASAP.

hawkw added a commit that referenced this pull request May 14, 2020
# 0.1.14 (May 14, 2020)

### Added

- **log**: When using the [`log`] compatibility feature alongside a 
  `tracing` `Subscriber`, log records for spans now include span IDs
  (#613)
- **attributes**: Support for using `#[instrument]` on methods that are
  part of [`async-trait`] trait implementations (#711)
- **attributes**: Optional `#[instrument(err)]` argument to 
  automatically emit an event if an instrumented function returns 
  `Err` (#637) 
- Added `#[must_use]` attribute to the guard returned by
  `subscriber::set_default` (#685)
  
### Changed

- **log**: Made [`log`] records emitted by spans much less noisy when
  span IDs are not available (#613)
 
### Fixed

- Several typos in the documentation (#656, #710, #715)

Thanks to @FintanH, @shepmaster, @inanna-malick, @zekisharif, @bkchr,
@majecty, @ilana and @nightmared for contributing to this release! 

[`async-trait`]: https://crates.io/crates/async-traite! 
[`log`]: https://crates.io/crates/log
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
crate/tracing Related to the `tracing` crate kind/feature New feature or request
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Don't forward empty span messages to log
3 participants